home *** CD-ROM | disk | FTP | other *** search
/ Sprite 1984 - 1993 / Sprite 1984 - 1993.iso / src / machserver / 1.098 / rpc / rpcTrace.c < prev    next >
C/C++ Source or Header  |  1991-05-17  |  11KB  |  391 lines
  1. /*
  2.  * rpcTrace.c --
  3.  *
  4.  *    The tracing routines for the Rpc system.  As messages are moved
  5.  *    through the RPC system time-stamped trace records can be taken
  6.  *    to see where the system spends its time.  The circular buffer
  7.  *    of trace records can be dumped to a file or printed to the console.
  8.  *
  9.  * Copyright (C) 1986 Regents of the University of California
  10.  * All rights reserved.
  11.  */
  12.  
  13. #ifndef lint
  14. static char rcsid[] = "$Header: /sprite/src/kernel/rpc/RCS/rpcTrace.c,v 9.4 91/05/17 10:43:09 kupfer Exp $ SPRITE (Berkeley)";
  15. #endif /* not lint */
  16.  
  17.  
  18. #include <sprite.h>
  19. #include <stdio.h>
  20. #include <bstring.h>
  21. #include <rpc.h>
  22. #include <rpcInt.h>
  23. #include <rpcTrace.h>
  24. #include <rpcServer.h>
  25. #include <net.h>
  26. #include <status.h>
  27. #include <dbg.h>
  28. #include <fs.h>
  29. #include <timer.h>
  30. #include <string.h>
  31. #include <dump.h>
  32.  
  33. /*
  34.  * The circular buffer of trace records.
  35.  */
  36. #ifdef CLEAN
  37. Boolean        rpc_Tracing = FALSE;    /* No tracing in clean version  */
  38. #else
  39. Boolean        rpc_Tracing = TRUE;    /* flag to turn on tracing */
  40. #endif /* not CLEAN */
  41.  
  42. Trace_Header    rpcTraceHdr;        /* Trace header info */
  43. Trace_Header    *rpcTraceHdrPtr = &rpcTraceHdr;
  44. /*
  45.  * The results of some standard benchmarks are cached so they
  46.  * get printed out with the trace records.
  47.  */
  48. Time rpcDeltaTime;        /* Average time per RPC */
  49. Time rpcEmptyStampTime;        /* The time to take a trace record without
  50.                  * copying the packet header */
  51. Time rpcFullStampTime;        /* The time to take a trace record that
  52.                  * includes copying the packet header */
  53.  
  54. /*
  55.  *----------------------------------------------------------------------
  56.  *
  57.  * Rpc_PrintTrace --
  58.  *
  59.  *    Print out the last few trace records.  Can be called from
  60.  *    the debugger or via the Test_Stat system call or from an L1 
  61.  *    console command.
  62.  *
  63.  * Results:
  64.  *    None.
  65.  *
  66.  * Side effects:
  67.  *    Print out the trace records on the console.
  68.  *
  69.  *----------------------------------------------------------------------
  70.  */
  71. void
  72. Rpc_PrintTrace(clientData)
  73.     ClientData clientData; /* The number (of most recent) records to print */
  74. {
  75. #ifndef CLEAN
  76.     int numRecords = (int)clientData;
  77.     register int i;    /* Index into trace table */
  78.     int stopIndex;    /* copy of rpcTraceIndex */
  79.     Time baseTime, deltaTime;    /* Times for print out */
  80.     Trace_Record *recordPtr;
  81.     RpcHdr    *rpcHdrPtr;
  82.     int c;        /* Used to identify record types in output */
  83.     char flagString[8];    /* Used to format rpc header flags */
  84.     int stringIndex;
  85.     int linesPrinted = 0;
  86.  
  87.     rpcTraceHdrPtr->flags |= TRACE_INHIBIT;
  88.     if (numRecords > rpcTraceHdrPtr->numRecords) {
  89.     numRecords = rpcTraceHdrPtr->numRecords;
  90.     }
  91.     /*
  92.      * Start the print numRecords before rpcTraceIndex.
  93.      * We make a copy of rpcTraceIndex in case in gets incremented
  94.      * during our set of print statements.
  95.      */
  96.     i = (rpcTraceHdrPtr->currentRecord + RPC_TRACE_LEN - numRecords)
  97.         % RPC_TRACE_LEN;
  98.     stopIndex = rpcTraceHdrPtr->currentRecord;
  99.  
  100.     printf("\n");
  101. #define PRINT_HEADER() \
  102.     printf("%6s %4s %6s %5s %4s %4s %10s %5s %5s %5s %8s\n", \
  103.     "ID", "type", "time", "flags", "srvr", "clnt", "cmd   ", \
  104.     "psize", "dsize", "doff", "fragInfo")
  105.  
  106.     baseTime.seconds = 0;
  107.     baseTime.microseconds = 0;
  108.     do {
  109.     if (linesPrinted % DUMP_LINES_PER_SCREEN == 0) {
  110.         PRINT_HEADER();
  111.     }
  112.     recordPtr = &rpcTraceHdrPtr->recordArray[i];
  113.     Time_Subtract(recordPtr->time, baseTime, &deltaTime);
  114.  
  115.     rpcHdrPtr = (RpcHdr *)recordPtr->traceData;
  116.     printf("%6x ", rpcHdrPtr->ID);
  117.  
  118.     switch(recordPtr->event) {
  119.         default:
  120.         printf("{%d}", recordPtr->event);
  121.         break;
  122.         case RPC_INPUT:
  123.         printf("in ");
  124.         break;
  125.         case RPC_ETHER_OUT:
  126.         printf("out");
  127.         break;
  128.         case RPC_OUTPUT:
  129.         printf("out");
  130.         break;
  131.         case RPC_CLIENT_a:        /* Client interrupt time stamps */
  132.         case RPC_CLIENT_b:
  133.         case RPC_CLIENT_c:
  134.         case RPC_CLIENT_d:
  135.         case RPC_CLIENT_e:
  136.         case RPC_CLIENT_f:
  137.         c = recordPtr->event - RPC_CLIENT_a + 'a';
  138.         printf("Ci%c", c);
  139.         break;
  140.         case RPC_CLIENT_A:        /* Client process level time stamps */
  141.         case RPC_CLIENT_B:
  142.         case RPC_CLIENT_C:
  143.         case RPC_CLIENT_D:
  144.         case RPC_CLIENT_E:
  145.         case RPC_CLIENT_F:
  146.         c = recordPtr->event - RPC_CLIENT_A + 'A';
  147.         printf("Cp%c", c);
  148.         break;
  149.         case RPC_SERVER_a:        /* Server interrupt time stamps */
  150.         case RPC_SERVER_b:
  151.         case RPC_SERVER_c:
  152.         case RPC_SERVER_d:
  153.         case RPC_SERVER_e:
  154.         case RPC_SERVER_f:
  155.         c = recordPtr->event - RPC_SERVER_a + 'a';
  156.         printf("Si%c", c);
  157.         break;
  158.         case RPC_SERVER_A:        /* Server process level time stamps */
  159.         case RPC_SERVER_B:
  160.         case RPC_SERVER_C:
  161.         case RPC_SERVER_D:
  162.         case RPC_SERVER_E:
  163.         case RPC_SERVER_F:
  164.         c = recordPtr->event - RPC_SERVER_A + 'A';
  165.         printf("Sp%c", c);
  166.         break;
  167.         case RPC_CLIENT_OUT:
  168.         printf("Cx ");
  169.         break;
  170.         case RPC_SERVER_OUT:
  171.         printf("Sx ");
  172.         break;
  173.     }
  174.  
  175.     printf(" %3d.%04d",
  176.                deltaTime.seconds,
  177.                deltaTime.microseconds / 100);
  178.     baseTime = recordPtr->time;
  179.     switch(rpcHdrPtr->flags & RPC_TYPE) {
  180.         case RPC_REQUEST:
  181.         flagString[0] = 'Q';
  182.         break;
  183.         case RPC_REPLY:
  184.         flagString[0] = 'R';
  185.         break;
  186.         case RPC_NACK:
  187.         flagString[0] = 'N';
  188.         break;
  189.         case RPC_ACK:
  190.         flagString[0] = 'A';
  191.         break;
  192.         default:
  193.         flagString[0] = '-';
  194.     }
  195.     stringIndex = 1;
  196.     if (rpcHdrPtr->flags & RPC_PLSACK) {
  197.         flagString[stringIndex++] = 'p';
  198.     }
  199.     if (rpcHdrPtr->flags & RPC_LASTFRAG) {
  200.         flagString[stringIndex++] = 'f';
  201.     }
  202.     if (rpcHdrPtr->flags & RPC_CLOSE) {
  203.         flagString[stringIndex++] = 'c';
  204.     }
  205.     if (rpcHdrPtr->flags & RPC_ERROR) {
  206.         flagString[stringIndex++] = 'e';
  207.     }
  208.     flagString[stringIndex] = '\0';
  209.     printf(" %2s", flagString);
  210.     printf(" %3d %d %3d %d ",
  211.                rpcHdrPtr->serverID, rpcHdrPtr->serverHint,
  212.                rpcHdrPtr->clientID, rpcHdrPtr->channel);
  213.     if (((rpcHdrPtr->flags & RPC_ERROR) == 0) &&
  214.         rpcHdrPtr->command >= 0 && rpcHdrPtr->command <= RPC_LAST_COMMAND) {
  215.         printf("%-8s", rpcService[rpcHdrPtr->command].name);
  216.     } else {
  217.         printf("%8x", rpcHdrPtr->command);
  218.     }
  219.     printf(" %5d %5d %5d %2d %2x %5d",
  220.                rpcHdrPtr->paramSize,
  221.                rpcHdrPtr->dataSize,
  222.                rpcHdrPtr->dataOffset,
  223.                rpcHdrPtr->numFrags,
  224.                rpcHdrPtr->fragMask,
  225.                rpcHdrPtr->delay);
  226.     printf("\n");
  227.     ++linesPrinted;
  228.  
  229.     i = (i + 1) % RPC_TRACE_LEN;
  230.     } while (i != stopIndex);
  231.     PRINT_HEADER();
  232.     printf("Delta time = %6d.%06d\n", rpcDeltaTime.seconds,
  233.               rpcDeltaTime.microseconds);
  234.     rpcTraceHdrPtr->flags &= ~TRACE_INHIBIT;
  235. #endif /* not CLEAN */
  236. }
  237.  
  238. /*
  239.  *----------------------------------------------------------------------
  240.  *
  241.  * Rpc_DumpTrace --
  242.  *
  243.  *    Dump out trace records to a file.  Can be called from
  244.  *     the debugger or via the Test_Stat system call.
  245.  *
  246.  * Results:
  247.  *    None.
  248.  *
  249.  * Side effects:
  250.  *    Dump out the trace records to the file.
  251.  *
  252.  *----------------------------------------------------------------------
  253.  */
  254. ReturnStatus
  255. Rpc_DumpTrace(firstRec, lastRec, fileName)
  256.     int firstRec;    /* The index of the first record to print.  The
  257.              * numbering is relative to the oldest record with
  258.              * the oldest record = 1 and the newest record =
  259.              * RPC_TRACE_LEN */
  260.     int lastRec;    /* The index of the last record to print. */
  261.     char *fileName;    /* Name of the file to which to write */
  262. {
  263. #ifndef CLEAN
  264.     register int i;        /* Index into trace table */
  265.     int stopIndex;        /* copy of rpcTraceIndex */
  266.     int offset;            /* file offset */
  267.     Fs_Stream *streamPtr;    /* File to write to */
  268.     ReturnStatus status;    /* Return code */
  269.     Rpc_TraceFileHdr rpcFileHdr;/* Trace file header */
  270.     Rpc_Trace    traceRecord;    /* Trace record for output file */
  271.     Trace_Record    *recordPtr;
  272.     int writeLen;
  273.  
  274.     rpcTraceHdrPtr->flags |= TRACE_INHIBIT;
  275.  
  276.     status = Fs_Open(fileName, FS_CREATE|FS_WRITE, FS_FILE, 0666, &streamPtr);
  277.     if (status != SUCCESS) {
  278.     goto exit;
  279.     }
  280.     /*
  281.      * Set up the header.
  282.      */
  283.     rpcFileHdr.version = rpc_NativeVersion;
  284.     rpcFileHdr.numRecords = lastRec - firstRec + 1;
  285.     rpcFileHdr.rpcDeltaTime = rpcDeltaTime;
  286.     rpcFileHdr.emptyStampMicroseconds = rpcEmptyStampTime.microseconds;
  287.     rpcFileHdr.fullStampMicroseconds = rpcFullStampTime.microseconds;
  288.  
  289.     offset = 0;
  290.     writeLen = sizeof(Rpc_TraceFileHdr);
  291.     status = Fs_Write(streamPtr, (Address)&rpcTraceHdr, offset, &writeLen);
  292.     if (status != SUCCESS) {
  293.     (void)Fs_Close(streamPtr);
  294.     goto exit;
  295.     }
  296.     offset += writeLen;
  297.     
  298.     /*
  299.      * rpcTraceIndex points to record #1.  Map from record number to index.
  300.      */
  301.     i = (rpcTraceHdrPtr->currentRecord + firstRec - 1) % RPC_TRACE_LEN;
  302.     stopIndex = (rpcTraceHdrPtr->currentRecord + lastRec) % RPC_TRACE_LEN;
  303.  
  304.     do {
  305.     writeLen = sizeof(Rpc_Trace);
  306.     recordPtr = &rpcTraceHdrPtr->recordArray[i];
  307.     traceRecord.time = recordPtr->time;
  308.     traceRecord.type = recordPtr->event;
  309.     bcopy((Address)recordPtr->traceData, (Address)&traceRecord.rpcHdr,
  310.         sizeof(RpcHdr));
  311.     status = Fs_Write(streamPtr, (Address)&traceRecord,
  312.                      streamPtr->offset, &writeLen);
  313.     if (status != SUCCESS) {
  314.         (void)Fs_Close(streamPtr);
  315.         goto exit;
  316.     }
  317.     i = (i + 1) % RPC_TRACE_LEN;
  318.     } while (i != stopIndex);
  319.  
  320.     (void)Fs_Close(streamPtr);
  321.     status = SUCCESS;
  322. exit:
  323.     rpcTraceHdrPtr->flags &= ~TRACE_INHIBIT;
  324.     return(status);
  325. #endif /* not CLEAN */
  326. }
  327.  
  328. /*
  329.  *----------------------------------------------------------------------
  330.  *
  331.  * Rpc_StampTest --
  332.  *
  333.  *    This does a calibration timing of the RpcTrace routine.
  334.  *    A numer of calls are made to this routine and the time per
  335.  *    call is computed and printed onto the console.
  336.  *
  337.  * Results:
  338.  *    None.
  339.  *
  340.  * Side effects:
  341.  *    None.
  342.  *
  343.  *----------------------------------------------------------------------
  344.  */
  345. void
  346. Rpc_StampTest()
  347. {
  348. #ifndef CLEAN
  349.     int i;
  350.     Timer_Ticks startTime;
  351.     Timer_Ticks endTime;
  352.     Time diff;
  353.     RpcHdr junkRpcHdr;
  354.  
  355. #define NUMTIMES    1000
  356.  
  357. /*   printf("RpcTrace timing:  "); */
  358.     junkRpcHdr.flags = 0;
  359.  
  360.     Timer_GetCurrentTicks(&startTime);
  361.      for (i=0 ; i<NUMTIMES ; i++) {
  362.     RpcTrace((RpcHdr *)NIL, RPC_SERVER_OUT, "empty");
  363.      }
  364.     Timer_GetCurrentTicks(&endTime);
  365.  
  366.     Timer_SubtractTicks(endTime, startTime, &endTime);
  367.     Timer_TicksToTime(endTime, &diff);
  368.     Time_Divide(diff, NUMTIMES, &diff);
  369. /*   printf("empty = %d, ", diff.microseconds); */
  370.     rpcEmptyStampTime = diff;
  371.  
  372.  
  373.     Timer_GetCurrentTicks(&startTime);
  374.      for (i=0 ; i<NUMTIMES ; i++) {
  375.     RpcTrace(&junkRpcHdr, RPC_CLIENT_OUT, "full");
  376.      }
  377.     Timer_GetCurrentTicks(&endTime);
  378.  
  379.     Timer_SubtractTicks(endTime, startTime, &endTime);
  380.     Timer_TicksToTime(endTime, &diff);
  381.     Time_Divide(diff, NUMTIMES, &diff);
  382. /*    printf("full = %d usecs\n", diff.microseconds); */
  383.     rpcFullStampTime = diff;
  384.  
  385.     for (i=0 ; i<4 ; i++) {
  386.     RpcTrace(&junkRpcHdr, RPC_SERVER_OUT, "full");
  387.     RpcTrace((RpcHdr *)NIL, RPC_CLIENT_OUT, "empty");
  388.     }
  389. #endif /* not CLEAN */
  390. }
  391.